Replacing created_at with the block_timestamp #9728

mateusz-sekara · 2023-06-30T21:04:54Z

There are a couple of issues with current approach in which we perform ordering by the created_at

Sorting by `created_at` is done in memory

explain analyze SELECT * FROM evm_logs
                        WHERE evm_chain_id = 1
                        AND address = '\xbb0f07700587fee22c5863ed75a5e05b68fcac4763449a582987fa4e8e9a2d0f'
                        AND event_sig = '\xa32c5f1d88735034143171f18fbb4d447fbbe0fbf4c98733d54092a081ba5d2a'
                        AND created_at > '2010-10-10'
                       AND (block_number) <=  (SELECT COALESCE(block_number, 0) FROM evm_log_poller_blocks WHERE evm_chain_id = 1 order by block_number desc LIMIT 1)
                        ORDER BY created_at ASC;

 Gather Merge  (cost=63063.08..73999.94 rows=93738 width=235) (actual time=114.722..125.164 rows=33413 loops=1)
   Workers Planned: 2
   Params Evaluated: $0
   Workers Launched: 2
   InitPlan 1 (returns $0)
     ->  Limit  (cost=0.43..0.57 rows=1 width=16) (actual time=0.038..0.039 rows=1 loops=1)
           ->  Index Only Scan Backward using log_poller_blocks_pkey on evm_log_poller_blocks  (cost=0.43..96592.10 rows=671267 width=16) (actual time=0.036..0.036 rows=1 loops=1)
                 Index Cond: (evm_chain_id = '1'::numeric)
                 Heap Fetches: 1
   ->  Sort  (cost=62062.48..62179.65 rows=46869 width=235) (actual time=105.857..107.012 rows=11138 loops=3)
         Sort Key: evm_logs.created_at
         Sort Method: external merge  Disk: 5040kB
         Worker 0:  Sort Method: external merge  Disk: 2112kB
         Worker 1:  Sort Method: external merge  Disk: 2112kB
         ->  Parallel Seq Scan on evm_logs  (cost=0.00..53137.80 rows=46869 width=235) (actual time=29.668..98.472 rows=11138 loops=3)
               Filter: ((created_at > '2010-10-10 00:00:00+00'::timestamp with time zone) AND (block_number <= $0) AND (evm_chain_id = '1'::numeric) AND (address = '\xbb0f07700587fee22c5863ed75a5e05b68fcac4763449a582987fa4e8e9a2d0f'::bytea) AND (event_sig = '\xa32c5f1d88735034143171f18fbb4d447fbbe0fbf4c98733d54092a081ba5d2a'::bytea))
               Rows Removed by Filter: 388862
 Planning Time: 0.456 ms
 Execution Time: 127.522 ms
(19 rows)

This query can be optimized a little by adding other columns to the index with includes or just returning columns from the index (not need to perform heap scan). However, the duration ends up around 100ms, with sorting still being run in memory.

`created_at` is initialized during runtime by picking the current time with `NOW()` function. Those times might differ between nodes causing nodes not reaching a consensus because they might get completely different logs from the log poller.

Current insert implementation

err := q.ExecQNamed(`INSERT INTO evm_logs 
(evm_chain_id, log_index, block_hash, block_number, block_timestamp, address, event_sig, topics, tx_hash, data, created_at) VALUES 
(:evm_chain_id, :log_index, :block_hash, :block_number, :block_timestamp, :address, :event_sig, :topics, :tx_hash, :data, NOW()) ON CONFLICT DO NOTHING`, logs[start:end])

Solution

Instead of sorting by date, let's sort by the block number. We can run one small subquery that picks block_number based on the timestamp and use it for filtering. This should save us some latency. What is more, instead of using create_at we should move to the block_timestamp which is the value created on chain so every node running code should get the same values

Query plans

Subquery picking the block_number based on the timestamp

chainlink_test=# explain analyze SELECT COALESCE(block_number, 0) FROM evm_log_poller_blocks WHERE evm_chain_id = 1 and block_timestamp > '2010-10-10' ORDER BY block_number LIMIT 1;
                                                                           QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.56..0.78 rows=1 width=16) (actual time=0.071..0.072 rows=1 loops=1)
   ->  Index Scan using log_poller_blocks_pkey on evm_log_poller_blocks  (cost=0.56..728781.59 rows=3328667 width=16) (actual time=0.069..0.069 rows=1 loops=1)
         Index Cond: (evm_chain_id = '1'::numeric)
         Filter: (block_timestamp > '2010-10-10 00:00:00+00'::timestamp with time zone)
 Planning Time: 0.317 ms
 Execution Time: 0.111 ms

Entire query

chainlink_test=# explain analyze SELECT * FROM evm_logs
                        WHERE evm_chain_id = 1
                        AND address = '\xbb0f07700587fee22c5863ed75a5e05b68fcac4763449a582987fa4e8e9a2d0f'
                        AND event_sig = '\xa32c5f1d88735034143171f18fbb4d447fbbe0fbf4c98733d54092a081ba5d2a'
                        AND block_number >= (SELECT COALESCE(block_number, 0) FROM evm_log_poller_blocks WHERE evm_chain_id = 1 and block_timestamp > '2010-10-10' ORDER BY block_number LIMIT 1)
                        AND (block_number) <=  (SELECT COALESCE(block_number, 0) FROM evm_log_poller_blocks WHERE evm_chain_id = 1 order by block_number desc LIMIT 1)
                        ORDER BY block_number ASC;

----------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=5975.62..5979.84 rows=1687 width=235) (actual time=57.351..61.167 rows=33413 loops=1)
   Sort Key: evm_logs.block_number
   Sort Method: external merge  Disk: 9240kB
   InitPlan 1 (returns $0)
     ->  Limit  (cost=0.43..0.57 rows=1 width=16) (actual time=0.055..0.056 rows=1 loops=1)
           ->  Index Scan using log_poller_blocks_pkey on evm_log_poller_blocks  (cost=0.43..98270.26 rows=671200 width=16) (actual time=0.053..0.053 rows=1 loops=1)
                 Index Cond: (evm_chain_id = '1'::numeric)
                 Filter: (block_timestamp > '2010-10-10 00:00:00+00'::timestamp with time zone)
   InitPlan 2 (returns $1)
     ->  Limit  (cost=0.43..0.57 rows=1 width=16) (actual time=0.026..0.026 rows=1 loops=1)
           ->  Index Only Scan Backward using log_poller_blocks_pkey on evm_log_poller_blocks evm_log_poller_blocks_1  (cost=0.43..96592.10 rows=671267 width=16) (actual time=0.026..0.026 rows=1 loops=1)
                 Index Cond: (evm_chain_id = '1'::numeric)
                 Heap Fetches: 1
   ->  Bitmap Heap Scan on evm_logs  (cost=216.06..5884.05 rows=1687 width=235) (actual time=17.892..33.581 rows=33413 loops=1)
         Recheck Cond: ((evm_chain_id = '1'::numeric) AND (block_number >= $0) AND (block_number <= $1) AND (address = '\xbb0f07700587fee22c5863ed75a5e05b68fcac4763449a582987fa4e8e9a2d0f'::bytea) AND (event_sig = '\xa32c5f1d88735034143171f18fbb4d447fbbe0fbf4c98733d54092a081ba5d2a'::bytea))
         Heap Blocks: exact=3705
         ->  Bitmap Index Scan on evm_logs_idx  (cost=0.00..215.64 rows=1687 width=0) (actual time=17.368..17.368 rows=33413 loops=1)
               Index Cond: ((evm_chain_id = '1'::numeric) AND (block_number >= $0) AND (block_number <= $1) AND (address = '\xbb0f07700587fee22c5863ed75a5e05b68fcac4763449a582987fa4e8e9a2d0f'::bytea) AND (event_sig = '\xa32c5f1d88735034143171f18fbb4d447fbbe0fbf4c98733d54092a081ba5d2a'::bytea))
 Planning Time: 0.595 ms
 Execution Time: 64.111 ms

github-actions · 2023-06-30T21:05:20Z

I see that you haven't updated any CHANGELOG files. Would it make sense to do so?

samsondav · 2023-07-10T13:17:29Z

core/chains/evm/logpoller/orm.go

+			AND block_number >= (SELECT COALESCE(block_number, 0) FROM evm_log_poller_blocks WHERE evm_chain_id = $1 and block_timestamp > $6 ORDER BY block_number LIMIT 1)
 			AND (block_number + $7) <= (SELECT COALESCE(block_number, 0) FROM evm_log_poller_blocks WHERE evm_chain_id = $1 ORDER BY block_number DESC LIMIT 1)
-			ORDER BY created_at ASC`, utils.NewBig(o.chainID), address, eventSig.Bytes(), topicIndex+1, pq.ByteaArray(topicValuesBytes), after, confs)
+			ORDER BY block_number ASC`, utils.NewBig(o.chainID), address, eventSig.Bytes(), topicIndex+1, pq.ByteaArray(topicValuesBytes), after, confs)


Understand it might be tricky, can we have a test case for it?

@samsondav please take a look, wrote a couple of tests. Additionally, I reverted changes from orm.go and run those tests against the old implementation - they did not pass, because of created_at behavior - which is expected ;)

reductionista

I'm tempted to say we should change the name to SelectLogsAfterBlockTimestamp to avoid confusion, but I guess probably best to leave as-is to avoid an unnecessary API change.

mateusz-sekara · 2023-07-11T12:25:56Z

I'm tempted to say we should change the name to SelectLogsAfterBlockTimestamp to avoid confusion, but I guess probably best to leave as-is to avoid an unnecessary API change.

We can give it a try in a separate PR ;)

cl-sonarqube-production · 2023-07-30T15:35:52Z

SonarQube Quality Gate

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

100.0% Coverage
0.0% Duplication

…h other log poller functions (block_no, log_index)

cl-sonarqube-production · 2023-09-19T09:58:36Z

SonarQube Quality Gate

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

100.0% Coverage
0.0% Duplication

mateusz-sekara marked this pull request as ready for review July 4, 2023 11:04

mateusz-sekara requested review from samsondav and prashantkumar1982 as code owners July 4, 2023 11:04

mateusz-sekara requested review from connorwstein, dimkouv and reductionista July 4, 2023 11:04

samsondav reviewed Jul 10, 2023

View reviewed changes

mateusz-sekara force-pushed the fix/log-poller-created-at branch from 414a28a to ee34bb1 Compare July 10, 2023 16:33

mateusz-sekara requested a review from samsondav July 10, 2023 16:35

samsondav previously approved these changes Jul 10, 2023

View reviewed changes

reductionista previously approved these changes Jul 10, 2023

View reviewed changes

mateusz-sekara dismissed stale reviews from reductionista and samsondav via a367f9d July 12, 2023 15:57

mateusz-sekara requested review from reductionista and samsondav July 12, 2023 17:35

samsondav previously approved these changes Jul 12, 2023

View reviewed changes

mateusz-sekara dismissed samsondav’s stale review via aff6ff6 July 26, 2023 08:41

mateusz-sekara force-pushed the fix/log-poller-created-at branch 3 times, most recently from 007f14f to 5dc8bf0 Compare July 30, 2023 15:19

Replacing created_at with the block_timestamp. Ordering alignment wit…

a6ac8b3

…h other log poller functions (block_no, log_index)

mateusz-sekara force-pushed the fix/log-poller-created-at branch from 5dc8bf0 to ae5b3d0 Compare September 19, 2023 09:25

Post rebase fixes

c62b417

mateusz-sekara force-pushed the fix/log-poller-created-at branch from ae5b3d0 to c62b417 Compare September 19, 2023 09:44

mateusz-sekara closed this Sep 19, 2023

mateusz-sekara deleted the fix/log-poller-created-at branch September 19, 2023 10:44

mateusz-sekara mentioned this pull request Sep 21, 2023

CCIP-1053 Replace filtering by created_at with filtering by block_timestamp #10743

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Replacing created_at with the block_timestamp #9728

Replacing created_at with the block_timestamp #9728

mateusz-sekara commented Jun 30, 2023 •

edited

Loading

github-actions bot commented Jun 30, 2023

samsondav Jul 10, 2023

mateusz-sekara Jul 10, 2023

reductionista left a comment

mateusz-sekara commented Jul 11, 2023

cl-sonarqube-production bot commented Jul 30, 2023

cl-sonarqube-production bot commented Sep 19, 2023

Replacing created_at with the block_timestamp #9728

Replacing created_at with the block_timestamp #9728

Conversation

mateusz-sekara commented Jun 30, 2023 • edited Loading

Sorting by created_at is done in memory

created_at is initialized during runtime by picking the current time with NOW() function. Those times might differ between nodes causing nodes not reaching a consensus because they might get completely different logs from the log poller.

Solution

Query plans

github-actions bot commented Jun 30, 2023

samsondav Jul 10, 2023

Choose a reason for hiding this comment

mateusz-sekara Jul 10, 2023

Choose a reason for hiding this comment

reductionista left a comment

Choose a reason for hiding this comment

mateusz-sekara commented Jul 11, 2023

cl-sonarqube-production bot commented Jul 30, 2023

cl-sonarqube-production bot commented Sep 19, 2023

mateusz-sekara commented Jun 30, 2023 •

edited

Loading

Sorting by `created_at` is done in memory

`created_at` is initialized during runtime by picking the current time with `NOW()` function. Those times might differ between nodes causing nodes not reaching a consensus because they might get completely different logs from the log poller.